root/trunk/libffado/src/debugmodule/debugmodule.cpp

Revision 681, 17.4 kB (checked in by ppalmers, 15 years ago)

move truncated warning to the message itself instead of printf on stdout

  • Property svn:eol-style set to native
  • Property svn:keywords set to Author Date Id Revision
Line 
1 /*
2  * Copyright (C) 2005-2007 by Daniel Wagner
3  * Copyright (C) 2005-2007 by Pieter Palmers
4  *
5  * This file is part of FFADO
6  * FFADO = Free Firewire (pro-)audio drivers for linux
7  *
8  * FFADO is based upon FreeBoB
9  *
10  * This library is free software; you can redistribute it and/or
11  * modify it under the terms of the GNU Lesser General Public
12  * License version 2.1, as published by the Free Software Foundation;
13  *
14  * This library is distributed in the hope that it will be useful,
15  * but WITHOUT ANY WARRANTY; without even the implied warranty of
16  * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
17  * Lesser General Public License for more details.
18  *
19  * You should have received a copy of the GNU Lesser General Public
20  * License along with this library; if not, write to the Free Software
21  * Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston,
22  * MA 02110-1301 USA
23  */
24
25 #include "debugmodule.h"
26
27 #include <stdarg.h>
28 #include <netinet/in.h>
29
30 #include <iostream>
31
32 #include <time.h>
33
34 #define DO_MESSAGE_BUFFER_PRINT
35
36 #ifndef DO_MESSAGE_BUFFER_PRINT
37         #warning Printing debug info without ringbuffer, not RT-safe!
38 #endif
39
40 using namespace std;
41
42 struct ColorEntry  {
43     const char* preSequence;
44     const char* postSequence;
45 };
46
47 ColorEntry colorTable[] = {
48     { "\033[31mFatal",   "\033[0m" },
49     { "\033[31mError",   "\033[0m" },
50     { "\033[31mWarning", "\033[0m" },
51     { "Debug",           ""        },
52 };
53
54
55 DebugModule::DebugModule( std::string name,  debug_level_t level )
56     : m_name( name )
57     , m_level( level )
58 {
59     if ( !DebugModuleManager::instance()->registerModule( *this ) ) {
60         cerr << "Could not register DebugModule (" << name
61              << ") at DebugModuleManager"
62              << endl;
63     }
64 }
65
66 DebugModule::~DebugModule()
67 {
68 //     if ( m_level >= eDL_VeryVerbose ) {
69 //         cout << "Unregistering "
70 //              << this->getName()
71 //              << " at DebugModuleManager"
72 //              << endl;
73 //     }
74     if ( !DebugModuleManager::instance()->unregisterModule( *this ) ) {
75         cerr << "Could not unregister DebugModule at DebugModuleManager"
76              << endl;
77     }
78
79 }
80
81 void
82 DebugModule::printShort( debug_level_t level,
83                          const char* format,
84                          ... ) const
85 {
86     va_list arg;
87
88     va_start( arg, format );
89     DebugModuleManager::instance()->backlog_va_print( format, arg );
90     va_end( arg );
91
92     if ( level > m_level ) {
93         return;
94     }
95
96     va_start( arg, format );
97     DebugModuleManager::instance()->va_print( format, arg );
98     va_end( arg );
99 }
100
101 void
102 DebugModule::print( debug_level_t level,
103                     const char*   file,
104                     const char*   function,
105                     unsigned int  line,
106                     const char*   format,
107                     ... ) const
108 {
109     va_list arg;
110     va_start( arg, format );
111
112     // remove the path info from the filename
113     const char *f = file;
114     const char *fname = file;
115     while((f=strstr(f, "/"))) {
116         f++; // move away from delimiter
117         fname=f;
118     }
119    
120     // add a timing timestamp
121     struct timespec ts;
122     clock_gettime(CLOCK_MONOTONIC, &ts);
123     uint32_t ts_usec=(uint32_t)(ts.tv_sec * 1000000LL + ts.tv_nsec / 1000LL);
124    
125     va_start( arg, format );
126     DebugModuleManager::instance()->backlog_print( "%010lu: %s (%s)[%4d] %s: ",
127                  ts_usec, getPreSequence( level ),
128                  fname,  line,  function );
129     DebugModuleManager::instance()->backlog_va_print( format, arg );
130     DebugModuleManager::instance()->backlog_print( "%s", getPostSequence( level ) );
131     va_end( arg );
132
133     if ( level > m_level ) {
134         return;
135     }
136
137     va_start( arg, format );
138     DebugModuleManager::instance()->print( "%010lu: %s (%s)[%4d] %s: ",
139                  ts_usec, getPreSequence( level ),
140                  fname,  line,  function );
141     DebugModuleManager::instance()->va_print( format, arg );
142     DebugModuleManager::instance()->print( "%s", getPostSequence( level ) );
143     va_end( arg );
144 }
145
146 const char*
147 DebugModule::getPreSequence( debug_level_t level ) const
148 {
149     if ( ( level <= eDL_Normal ) && ( level >= eDL_Fatal ) ) {
150         return colorTable[level].preSequence;
151     }
152     return colorTable[eDL_Normal].preSequence;
153 }
154
155 const char*
156 DebugModule::getPostSequence( debug_level_t level ) const
157 {
158     if ( ( level <= eDL_Normal ) && ( level >= eDL_Fatal ) ) {
159         return colorTable[level].postSequence;
160     }
161     return colorTable[eDL_Normal].postSequence;
162 }
163
164 //--------------------------------------
165
166 DebugModuleManager* DebugModuleManager::m_instance = 0;
167
168 DebugModuleManager::DebugModuleManager()
169     : mb_initialized(0)
170     , mb_inbuffer(0)
171     , mb_outbuffer(0)
172     , mb_overruns(0)
173     , bl_mb_inbuffer(0)
174 {
175
176 }
177
178 DebugModuleManager::~DebugModuleManager()
179 {
180     // cleanin up leftover modules
181     for ( DebugModuleVectorIterator it = m_debugModules.begin();
182           it != m_debugModules.end();
183           ++it )
184     {
185         fprintf(stderr,"Cleaning up leftover debug module: %s\n",(*it)->getName().c_str());
186         m_debugModules.erase( it );
187         delete *it;
188     }
189
190     if (!mb_initialized)
191         return;
192
193     pthread_mutex_lock(&mb_write_lock);
194     mb_initialized = 0;
195     pthread_cond_signal(&mb_ready_cond);
196     pthread_mutex_unlock(&mb_write_lock);
197
198     pthread_join(mb_writer_thread, NULL);
199     mb_flush();
200
201     if (mb_overruns)
202         fprintf(stderr, "WARNING: %d message buffer overruns!\n",
203             mb_overruns);
204     else
205         fprintf(stderr, "no message buffer overruns\n");
206
207     pthread_mutex_destroy(&mb_write_lock);
208     pthread_cond_destroy(&mb_ready_cond);
209
210 }
211
212 bool
213 DebugModuleManager::init()
214 {
215     if (mb_initialized)
216         return true;
217
218         // if ( m_level >= eDL_VeryVerbose )
219         //         cout << "DebugModuleManager init..." << endl;
220
221     pthread_mutex_init(&mb_write_lock, NULL);
222     pthread_mutex_init(&mb_flush_lock, NULL);
223     pthread_cond_init(&mb_ready_cond, NULL);
224
225     mb_overruns = 0;
226     mb_initialized = 1;
227
228     pthread_mutex_init(&bl_mb_write_lock, NULL);
229
230     if (pthread_create(&mb_writer_thread, NULL, &mb_thread_func, (void *)this) != 0)
231          mb_initialized = 0;
232
233     return true;
234 }
235
236 DebugModuleManager*
237 DebugModuleManager::instance()
238 {
239     if ( !m_instance ) {
240         m_instance = new DebugModuleManager;
241         if ( !m_instance ) {
242             cerr << "DebugModuleManager::instance Failed to create "
243                  << "DebugModuleManager" << endl;
244         }
245         if ( !m_instance->init() ) {
246             cerr << "DebugModuleManager::instance Failed to init "
247                  << "DebugModuleManager" << endl;
248         }
249     }
250     return m_instance;
251 }
252
253 bool
254 DebugModuleManager::registerModule( DebugModule& debugModule )
255 {
256     bool already_present=false;
257
258     for ( DebugModuleVectorIterator it = m_debugModules.begin();
259           it != m_debugModules.end();
260           ++it )
261     {
262         if ( *it == &debugModule ) {
263             already_present=true;
264             return true;
265         }
266     }
267
268     if (already_present) {
269         cerr << "DebugModuleManager::registerModule: Module already registered: "
270             << "DebugModule (" << debugModule.getName() << ")" << endl;
271     } else {
272         m_debugModules.push_back( &debugModule );
273     }
274     return true;
275 }
276
277 bool
278 DebugModuleManager::unregisterModule( DebugModule& debugModule )
279 {
280
281     for ( DebugModuleVectorIterator it = m_debugModules.begin();
282           it != m_debugModules.end();
283           ++it )
284     {
285         if ( *it == &debugModule ) {
286             m_debugModules.erase( it );
287             return true;
288         }
289     }
290
291     cerr << "DebugModuleManager::unregisterModule: Could not unregister "
292          << "DebugModule (" << debugModule.getName() << ")" << endl;
293     return false;
294 }
295
296 bool
297 DebugModuleManager::setMgrDebugLevel( std::string name, debug_level_t level )
298 {
299     for ( DebugModuleVectorIterator it = m_debugModules.begin();
300           it != m_debugModules.end();
301           ++it )
302     {
303         if ( (*it)->getName() == name ) {
304             return (*it)->setLevel( level );
305         }
306     }
307
308     cerr << "setDebugLevel: Did not find DebugModule ("
309          << name << ")" << endl;
310     return false;
311 }
312
313 void
314 DebugModuleManager::flush()
315 {
316 #ifdef DO_MESSAGE_BUFFER_PRINT
317     mb_flush();
318 #else
319     fflush(stderr);
320 #endif
321 }
322
323 void
324 DebugModuleManager::mb_flush()
325 {
326     /* called WITHOUT the mb_write_lock */
327    
328     /* the flush lock is to allow a flush from multiple threads
329      * this allows a code section that outputs a lot of debug messages
330      * and that can be blocked to flush the buffer itself such that it
331      * does not overflow.
332      */
333     DebugModuleManager *m=DebugModuleManager::instance();
334     pthread_mutex_lock(&m->mb_flush_lock);
335     while (mb_outbuffer != mb_inbuffer) {
336         fputs(mb_buffers[mb_outbuffer], stderr);
337         mb_outbuffer = MB_NEXT(mb_outbuffer);
338     }
339     pthread_mutex_unlock(&m->mb_flush_lock);
340 }
341
342 void
343 DebugModuleManager::showBackLog()
344 {
345     fprintf(stderr, "=====================================================\n");
346     fprintf(stderr, "* BEGIN OF BACKLOG PRINT\n");
347     fprintf(stderr, "=====================================================\n");
348
349     for (unsigned int i=0; i<BACKLOG_MB_BUFFERS;i++) {
350         unsigned int idx=(i+bl_mb_inbuffer)%BACKLOG_MB_BUFFERS;
351         fputs(bl_mb_buffers[idx], stderr);
352     }
353     fprintf(stderr, "\n");
354
355     fprintf(stderr, "=====================================================\n");
356     fprintf(stderr, "* END OF BACKLOG PRINT\n");
357     fprintf(stderr, "=====================================================\n");
358 }
359
360 void *
361 DebugModuleManager::mb_thread_func(void *arg)
362 {
363
364     DebugModuleManager *m=static_cast<DebugModuleManager *>(arg);
365
366     /* The mutex is only to eliminate collisions between multiple
367      * writer threads and protect the condition variable. */
368      pthread_mutex_lock(&m->mb_write_lock);
369
370     while (m->mb_initialized) {
371          pthread_cond_wait(&m->mb_ready_cond, &m->mb_write_lock);
372
373          /* releasing the mutex reduces contention */
374          pthread_mutex_unlock(&m->mb_write_lock);
375          m->mb_flush();
376          pthread_mutex_lock(&m->mb_write_lock);
377     }
378
379      pthread_mutex_unlock(&m->mb_write_lock);
380
381     return NULL;
382 }
383
384 void
385 DebugModuleManager::backlog_print(const char *fmt, ...)
386 {
387     const char *warning = "WARNING: message truncated!\n";
388     const int warning_size = 32;
389     char msg[MB_BUFFERSIZE];
390     va_list ap;
391
392     unsigned int ntries;
393     struct timespec wait = {0,50000};
394
395     /* format the message first */
396     va_start(ap, fmt);
397     if (vsnprintf(msg, BACKLOG_MB_BUFFERSIZE-warning_size, fmt, ap)
398         >= (BACKLOG_MB_BUFFERSIZE-warning_size)) {
399         // output a warning if the message was truncated
400         snprintf(msg+BACKLOG_MB_BUFFERSIZE-warning_size, warning_size, "%s", warning);
401     }
402     va_end(ap);
403
404     // the backlog
405     ntries=5;
406     while (ntries) { // try a few times
407         if (pthread_mutex_trylock(&bl_mb_write_lock) == 0) {
408             strncpy(bl_mb_buffers[bl_mb_inbuffer], msg, BACKLOG_MB_BUFFERSIZE);
409             bl_mb_inbuffer = BACKLOG_MB_NEXT(bl_mb_inbuffer);
410             pthread_mutex_unlock(&bl_mb_write_lock);
411             break;
412         } else {
413             nanosleep(&wait, NULL);
414             ntries--;
415         }
416     }
417     // just bail out should it have failed
418 }
419
420 void
421 DebugModuleManager::print(const char *fmt, ...)
422 {
423     const char *warning = "WARNING: message truncated!\n";
424     const int warning_size = 32;
425     char msg[MB_BUFFERSIZE];
426     va_list ap;
427
428 #ifdef DO_MESSAGE_BUFFER_PRINT
429     unsigned int ntries;
430     struct timespec wait = {0,50000};
431 #endif
432
433     /* format the message first, to reduce lock contention */
434     va_start(ap, fmt);
435     if (vsnprintf(msg, MB_BUFFERSIZE-warning_size, fmt, ap) >= MB_BUFFERSIZE-warning_size) {
436         // output a warning if the message was truncated
437         snprintf(msg+MB_BUFFERSIZE-warning_size, warning_size, "%s", warning);
438     }
439     va_end(ap);
440
441     if (!mb_initialized) {
442         /* Unable to print message with realtime safety.
443          * Complain and print it anyway. */
444         fprintf(stderr, "ERROR: messagebuffer not initialized: %s",
445             msg);
446         return;
447     }
448
449 #ifdef DO_MESSAGE_BUFFER_PRINT
450     ntries=5;
451     while (ntries) { // try a few times
452         if (pthread_mutex_trylock(&mb_write_lock) == 0) {
453             strncpy(mb_buffers[mb_inbuffer], msg, MB_BUFFERSIZE);
454             mb_inbuffer = MB_NEXT(mb_inbuffer);
455             pthread_cond_signal(&mb_ready_cond);
456             pthread_mutex_unlock(&mb_write_lock);
457             break;
458         } else {
459             nanosleep(&wait, NULL);
460             ntries--;
461         }
462     }
463     if (ntries==0) {  /* lock collision */
464         //         atomic_add(&mb_overruns, 1);
465         // FIXME: atomicity
466         mb_overruns++; // skip the atomicness for now
467     }
468 #else
469     fprintf(stderr,msg);
470 #endif
471 }
472
473 void
474 DebugModuleManager::backlog_va_print (const char *fmt, va_list ap)
475 {
476     const char *warning = "WARNING: message truncated!\n";
477     const int warning_size = 32;
478     char msg[MB_BUFFERSIZE];
479     unsigned int ntries;
480     struct timespec wait = {0,50000};
481
482     /* format the message first */
483     if (vsnprintf(msg, BACKLOG_MB_BUFFERSIZE-warning_size, fmt, ap)
484         >= BACKLOG_MB_BUFFERSIZE-warning_size) {
485         // output a warning if the message was truncated
486         snprintf(msg+BACKLOG_MB_BUFFERSIZE-warning_size, warning_size, "%s", warning);
487     }
488
489     // the backlog
490     ntries=5;
491     while (ntries) { // try a few times
492         if (pthread_mutex_trylock(&bl_mb_write_lock) == 0) {
493             strncpy(bl_mb_buffers[bl_mb_inbuffer], msg, BACKLOG_MB_BUFFERSIZE);
494             bl_mb_inbuffer = BACKLOG_MB_NEXT(bl_mb_inbuffer);
495             pthread_mutex_unlock(&bl_mb_write_lock);
496             break;
497         } else {
498             nanosleep(&wait, NULL);
499             ntries--;
500         }
501     }
502     // just bail out should it have failed
503 }
504
505 void
506 DebugModuleManager::va_print (const char *fmt, va_list ap)
507 {
508     const char *warning = "WARNING: message truncated!\n";
509     const int warning_size = 32;
510     char msg[MB_BUFFERSIZE];
511
512 #ifdef DO_MESSAGE_BUFFER_PRINT
513     unsigned int ntries;
514     struct timespec wait = {0,50000};
515 #endif
516
517     /* format the message first, to reduce lock contention */
518     if (vsnprintf(msg, MB_BUFFERSIZE-warning_size, fmt, ap) >= MB_BUFFERSIZE-warning_size) {
519         // output a warning if the message was truncated
520         snprintf(msg+MB_BUFFERSIZE-warning_size, warning_size, "%s", warning);
521     }
522
523     if (!mb_initialized) {
524         /* Unable to print message with realtime safety.
525          * Complain and print it anyway. */
526         fprintf(stderr, "ERROR: messagebuffer not initialized: %s",
527             msg);
528         return;
529     }
530
531 #ifdef DO_MESSAGE_BUFFER_PRINT
532     ntries=5;
533     while (ntries) { // try a few times
534         if (pthread_mutex_trylock(&mb_write_lock) == 0) {
535             strncpy(mb_buffers[mb_inbuffer], msg, MB_BUFFERSIZE);
536             mb_inbuffer = MB_NEXT(mb_inbuffer);
537             pthread_cond_signal(&mb_ready_cond);
538             pthread_mutex_unlock(&mb_write_lock);
539             break;
540         } else {
541             nanosleep(&wait, NULL);
542             ntries--;
543         }
544     }
545    
546     if (ntries==0) {  /* lock collision */
547 //         atomic_add(&mb_overruns, 1);
548         // FIXME: atomicity
549         mb_overruns++; // skip the atomicness for now
550     }
551 #else
552     fprintf(stderr,msg);
553 #endif
554 }
555
556 //----------------------------------------
557
558 unsigned char
559 toAscii( unsigned char c )
560 {
561     if ( ( c > 31 ) && ( c < 126) ) {
562         return c;
563     } else {
564         return '.';
565     }
566 }
567
568 /* converts a quadlet to a uchar * buffer
569  * not implemented optimally, but clear
570  */
571 void
572 quadlet2char( quadlet_t quadlet, unsigned char* buff )
573 {
574     *(buff)   = (quadlet>>24)&0xFF;
575     *(buff+1) = (quadlet>>16)&0xFF;
576     *(buff+2) = (quadlet>> 8)&0xFF;
577     *(buff+3) = (quadlet)    &0xFF;
578 }
579
580 void
581 hexDump( unsigned char *data_start, unsigned int length )
582 {
583     unsigned int i=0;
584     unsigned int byte_pos;
585     unsigned int bytes_left;
586
587     if ( length <= 0 ) {
588         return;
589     }
590     if ( length >= 7 ) {
591         for ( i = 0; i < (length-7); i += 8 ) {
592             printf( "%04X: %02X %02X %02X %02X %02X %02X %02X %02X "
593                     "- [%c%c%c%c%c%c%c%c]\n",
594
595                     i,
596
597                     *(data_start+i+0),
598                     *(data_start+i+1),
599                     *(data_start+i+2),
600                     *(data_start+i+3),
601                     *(data_start+i+4),
602                     *(data_start+i+5),
603                     *(data_start+i+6),
604                     *(data_start+i+7),
605
606                     toAscii( *(data_start+i+0) ),
607                     toAscii( *(data_start+i+1) ),
608                     toAscii( *(data_start+i+2) ),
609                     toAscii( *(data_start+i+3) ),
610                     toAscii( *(data_start+i+4) ),
611                     toAscii( *(data_start+i+5) ),
612                     toAscii( *(data_start+i+6) ),
613                     toAscii( *(data_start+i+7) )
614                 );
615         }
616     }
617     byte_pos = i;
618     bytes_left = length - byte_pos;
619
620     printf( "%04X:" ,i );
621     for ( i = byte_pos; i < length; i += 1 ) {
622         printf( " %02X", *(data_start+i) );
623     }
624     for ( i=0; i < 8-bytes_left; i+=1 ) {
625         printf( "   " );
626     }
627
628     printf( " - [" );
629     for ( i = byte_pos; i < length; i += 1) {
630         printf( "%c", toAscii(*(data_start+i)));
631     }
632     for ( i = 0; i < 8-bytes_left; i += 1) {
633         printf( " " );
634     }
635
636     printf( "]" );
637     printf( "\n" );
638 }
639
640 void
641 hexDumpQuadlets( quadlet_t *data, unsigned int length )
642 {
643     unsigned int i=0;
644
645     if ( length <= 0 ) {
646         return;
647     }
648     for (i = 0; i< length; i += 1) {
649         printf( "%02d %04X: %08X (%08X)"
650                 "\n", i, i*4, data[i],ntohl(data[i]));
651     }
652 }
653
654
Note: See TracBrowser for help on using the browser.