Creating a Simple Golang Network Application, Part 2

Next I turned my thoughts to logging. If the processes are going to "log" things (eventually to a text file) I should probably create something to stub out that function.

Is that even the right word, stub? I used to think it was a placeholder so other parts of the application had something to call that could be fleshed out later. Apparently looking into the term I ended up discovering that it has a more specific meaning...and I'm not sure what it is called to create a function that does something, but the intention is to come back later to add or enhance the functionality; maybe the definition still fits.

But for my purposes here that doesn't matter. The point is, I wanted to have a separate, modular function call to do the work of printing stuff to the screen or dumping stuff to a text file.

So I created this:

func LogEvent(strFrom string, strMessage string) {

 fmt.Println("From " + strFrom + ": " + strMessage)
 
}

The function is called LogEvent(), and takes two string arguments. The strFrom is so the caller can insert the process (remember, asynchronous goroutines...) and strMessage is the message. This simplified form is going pretty much retain the previous incarnation's output, but under the hood I can greatly reduce duplicated code.

Also notice that I started using a naming convention of strNameOfFunction. I usually preface my variables with their type so I can keep track of them. The only time I didn't usually do that is using simple one-off single letter counters, like the "i" in the initial loop contained in main().

It started bugging me that my ListenToPort function didn't follow my variable naming convention. I had to rework it to use the logging function anyway, so I fixed it.

func ListenToPort(uint16Port uint16) {

 var strDiagMessage string

 strDiagMessage = "Listening to port " + strconv.FormatInt(int64(uint16Port),10)
 LogEvent(strconv.FormatInt(int64(uint16Port),10), strDiagMessage)
 
}

I created a string variable because, as I alluded previously, integers aren't strings. This was an easy way to make it clear that I'm converting something to a string and storing it in a nice little package to send off to another function. strDiagMessage is declared, then it's set to the diagnostic message for my testing and shuffled into LogEvent. I could have created another variable to store the name of the "port" it's listening on, but...meh.

The next item I started thinking about was communicating from the goroutines back to the calling process. Because the goroutines are asynchronous, doing anything that requires a check of the status of an individual goroutine requires some kind of communication channel to exchange data and "sync up" information. At this point I wanted to validate that the goroutines were running properly and could give a nod back to main() that those processes were ready.

This approach also meant I could get rid of the clunky timer. The timer is just a guesstimate of how long it will take all the goroutines to run and is rather sloppy. Time to modify some source code...

First, I won't need timers, so I remove the 'import "time"' line along with the time.Sleep and the associated "done" line as well as the comments referring to those lines. I use comments to explain what I'm doing for later reference mainly because I have the memory of a sieve, but I'm documenting everything here so for a short program like this I figure it's not really needed (and highly redundant when I'm elaborating in exposition.)

Next I create a channel. It's a Go method of intra-communication among asynchronous code; I'll spare you the details beyond the idea that if you want to pass data among routines, it's a handy data chute to slide information. And to be completely honest, channels seem a little tricky to get the hang of...

In my block of declarations, I create a channel called chanCommLine with:

chanCommLine := make(chan string)

Next I want to collect data from my goroutines. I change the definition of ListenToPort so it takes an additional argument:

func ListenToPort(uint16Port uint16, chanOutGoing chan<- string) {

Then I add a line to send both a "done" along with the "port number" (at this point, port number is a name-only thing...it's the port the particular routine is supposed to handle, not what it's actually doing. Don't get confused. Practically speaking it's an identifier of which goroutine is passing the message.)

 chanOutGoing <-"done " + strconv.FormatInt(int64(uint16Port),10)

The message sent into the channel is getting passed back to the main() function where something is listening for input from the channel conveyor belt. Of course something has to pass that channel to ListenToPort, so in main() where it's invoked I change the call to:

  go ListenToPort(i, chanCommLine)

Now I have to do something with that information. I add the following after all the go routines are spawned:

 i = 0

 for {

  strChanData:=<-chanCommLine
  if strChanData != "" {
   i++
   fmt.Println("Input detected from channel, loop " + strconv.FormatInt(int64(i),10) + " " + strChanData)
  }

  if i == 1024 {
   fmt.Println("Channels accounted for")
   break
  }
 }

What's happening here?

First I took the iterator from the previous loop and reused it, setting it to 0.

Next I create an infinite loop with "for" and inside create a string variable strChanData that is set to the data coming out of chanCommLine. Then, if the value isn't empty, another loop runs incrementing i and outputting a line telling the user that information was found from loop number something and at the end printing the data that came out of the channel.

When i hits 1024, the program prints that all the channels are accounted for and then "break" exits the infinite loop.

Notice this is comparing for 1024 while the loop spawning the goroutines counts to 1025? That's because of the point at which the comparison is being made. The loop creating the goroutines starts at 1, and once it's compared at the beginning of the final loop it will equal 1025 and not run again, leaving 1024 iterations. In this loop it starts at 0, runs a series of steps, then compares the state of the variable; if it's 1024 at the end of the last run, it stops. Rearranging the logic a bit could make it all consistent with one value (1024 or 1025) but I wanted the port counting to start at 1 and really, this isn't all that strange to figure out once you see the logic. I would wager that loop comparisons can be a huge source of difficulties and logic errors for new programmers, though.

How did I verify I have it running with the proper loop counts? I did a quick build ("go build" from the src directory) and ran my application with a "|grep 102" to see what popped out:

Input detected from channel, loop 102 done 874
From 1020: Listening to port 1020
From 1021: Listening to port 1021
From 1022: Listening to port 1022
From 1023: Listening to port 1023
From 1024: Listening to port 1024
Input detected from channel, loop 248 done 1020
Input detected from channel, loop 249 done 1021
Input detected from channel, loop 250 done 1022
Input detected from channel, loop 251 done 1023
Input detected from channel, loop 252 done 1024
From 102: Listening to port 102
Input detected from channel, loop 354 done 102
Input detected from channel, loop 1020 done 769
Input detected from channel, loop 1021 done 770
Input detected from channel, loop 1022 done 771
Input detected from channel, loop 1023 done 772
Input detected from channel, loop 1024 done 902

You can see the highest count is 1024. If the goroutines hit 1025, the lines starting with "From" would list a 1025, and if the channel loop hit 1025 then a line starting with "Input" would have a loop 1025 listed.

One important thing to note is that you can't treat the channel as if it were a variable. When something reads from the channel it is "emptied." In one version of the code I had tried to use the channel in a conditional check then output the contents in two separate statements; the number of loop iterations dropped to 512, only half of what was supposed to run. Why?

It happened because I was reading once as a conditional check, and in a second statement tried dumping the contents of the channel. What actually happened was it emptied when I checked the channel to evaluate for a condition then when the channel was used to print the contents it was getting the next item put into the channel, not the item used to check the condition.

On the bright side at least it was kind of obvious when the symptom was cutting the loop iterations in half...

A minor fix and voila! Communication from the goroutines to the caller! If you recall the earliest version of the program had a 2-second delay built in. This method of having channels tell main() that the goprocesses are all ready and listening means there should be a drastic drop in "do nothing" time. How long does the current version take to run?

I ran port_listen (the name of the application) on my somewhat old Mac running at 2.4 GHz on a Core 2 Duo processor using the "time" utility:

real 0m0.152s
user 0m0.010s
sys 0m0.010s

I'd say that's a bit of an improvement!

Here's what the source looks like at this point:

package main

import "fmt"
import "strconv"

func main() {

 var i uint16
 chanCommLine := make(chan string)
 
 for i = 1; i < 1025; i++ {
  go ListenToPort(i, chanCommLine)
 }

 i = 0

 for {
  strChanData:=<-chanCommLine
  if strChanData != "" {
   i++
   fmt.Println("Input detected from channel, loop " + strconv.FormatInt(int64(i),10) + " " + strChanData)
  }
  if i == 1024 {
   fmt.Println("Channels accounted for")
   break
  }
 }
}

func ListenToPort(uint16Port uint16, chanOutGoing chan<- string) {
 var strDiagMessage string

 strDiagMessage = "Listening to port " + strconv.FormatInt(int64(uint16Port),10)
 LogEvent(strconv.FormatInt(int64(uint16Port),10), strDiagMessage)
 chanOutGoing <-"done " + strconv.FormatInt(int64(uint16Port),10)
}

func LogEvent(strFrom string, strMessage string) {
 fmt.Println("From " + strFrom + ": " + strMessage)
}

This concludes part two!